EMR上でのspark-shellのログレベルの変更方法とその仕組について

EMR上でのspark-shellのログレベルの変更方法とその仕組について

#Hadoop
#Spark
#Amazon EMR
#AWS
Satoshi Noto

Satoshi Noto

facebook logohatena logotwitter logo
Clock Icon2016.07.07

この記事は公開されてから1年以上経過しています。情報が古い可能性がありますので、ご注意ください。

小ネタです。EMR上でspark-shellを利用する際のログレベルの変更方法について紹介します。また、それだけだと余りにも内容が少ないので、log4j.properties がどのようにして読み込まれるかについても解説します。

前提

以下の環境を前提としています。

  • emr-4.7.1 でアプリケーションは Hadoop, Spark
    • Sparkのバージョンは 1.6.1
  • ハードウェア構成は m1.medium を 1 台（検証用なのでマスターノードのみ）
  • EC2キーペアを設定（SSHで接続して操作するため）
  • 東京リージョン

AWS CLIだと以下のようなコマンドになります。KeyName, SubnetId, log-uriをご自身の環境に合わせればそのまま利用できるはずです。

aws emr create-cluster --applications Name=Hadoop Name=Spark \
  --ec2-attributes '{"KeyName":"XXXX","InstanceProfile":"EMR_EC2_DefaultRole","SubnetId":"subnet-dXXXX"}' \
  --service-role EMR_DefaultRole --enable-debugging --release-label emr-4.7.1 \
  --log-uri 's3n://aws-logs-XXXX-ap-northeast-1/elasticmapreduce/' --name 'Spark' \
  --instance-groups '[{"InstanceCount":1,"InstanceGroupType":"MASTER","InstanceType":"m1.medium","Name":"Master Instance Group"}]' \
  --region ap-northeast-1

spark-shellのログレベルの変更方法

先に忙しい方向けに結論だけ書いてしまいます。SSHでマスターノードにログインしたら以下のコマンドを実行するだけです。

$ sudo sed -i s/log4j.rootCategory=INFO/log4j.rootCategory=WARN/ /usr/lib/spark/conf/log4j.properties

前述はログレベルをINFOからWARNに変更しています。他のログレベルに変更する際はWARNの箇所を変更して下さい。

以下は、実際に変更する前と変更した後の差分についての解説になります。

デフォルト状態のspark-shell

まずは、SSHでマスターノードにログインしてspark-shellを起動したいと思います。

$ ssh -i /path/to/XXXX.pem -l hadoop ec2-XXX-XXX-XXX-XXX.ap-northeast-1.compute.amazonaws.com

[hadoop@ip-172-31-30-193 ~]$

次にspark-shellを起動します。

[hadoop@ip-172-31-30-193 ~]$ spark-shell 
16/06/20 08:47:19 INFO SecurityManager: Changing view acls to: hadoop
16/06/20 08:47:19 INFO SecurityManager: Changing modify acls to: hadoop
16/06/20 08:47:19 INFO SecurityManager: SecurityManager: authentication disabled; ui acls disabled; users with view permissions: Set(hadoop); users with modify permissions: Set(hadoop)
16/06/20 08:47:20 INFO HttpServer: Starting HTTP Server
16/06/20 08:47:20 INFO Utils: Successfully started service 'HTTP class server' on port 36688.
Welcome to
      ____              __
     / __/__  ___ _____/ /__
    _\ \/ _ \/ _ `/ __/  '_/
   /___/ .__/\_,_/_/ /_/\_\   version 1.6.1
      /_/

Using Scala version 2.10.5 (OpenJDK 64-Bit Server VM, Java 1.7.0_101)
Type in expressions to have them evaluated.
Type :help for more information.
16/06/20 08:47:32 INFO SparkContext: Running Spark version 1.6.1

...

16/06/20 08:48:50 INFO SessionState: Created HDFS directory: /tmp/hive/hadoop/6adf18eb-1094-4570-aa50-d826af448f07/_tmp_space.db
16/06/20 08:48:50 INFO SparkILoop: Created sql context (with Hive support)..
SQL context available as sqlContext.

scala>

起動されたことがある方は分かると思いますが、デフォルトのログレベルがINFOになっているため、起動するだけでも大量のログが出力されます。また、アクション実行時のログも大量に出力されます。

デフォルトの状態は確認できたのでexitでspark-shellを終了して下さい。

scala> exit
warning: there were 1 deprecation warning(s); re-run with -deprecation for details
16/06/20 09:05:46 INFO SparkContext: Invoking stop() from shutdown hook

...

16/06/20 09:05:46 INFO ShutdownHookManager: Deleting directory /mnt/tmp/spark-55f30538-ff9f-4e2e-80b6-1143052abe6c
16/06/20 09:05:46 INFO RemoteActorRefProvider$RemotingTerminator: Remoting shut down.
[hadoop@ip-172-31-30-193 ~]$

（exitですら大量にログが出力されていますね）

ログレベルをWARNに変更する

では、ログレベルをWARNに変更してみたいと思います。spark-shellはSPARK_HOME/conf/log4j.propertiesを利用するようになってるため *1、最初にsedコマンドで操作していた通り、このファイルに書かれているログレベルを書き換えます。EMRのマスターノードのSPARK_HOMEは/usr/lib/spark/となります *2。

[hadoop@ip-172-31-30-193 ~]$ ll /usr/lib/spark/
合計 76
-rw-r--r-- 1 root root 17352  6月 10 01:56 LICENSE
-rw-r--r-- 1 root root 23529  6月 10 01:56 NOTICE
drwxr-xr-x 3 root root  4096  6月 20 08:36 R
-rw-r--r-- 1 root root     0  6月 10 01:56 RELEASE
drwxr-xr-x 2 root root  4096  6月 20 08:36 bin
lrwxrwxrwx 1 root root    15  6月 20 08:36 conf -> /etc/spark/conf
drwxr-xr-x 3 root root  4096  6月 20 08:36 data
lrwxrwxrwx 1 root root    35  6月 20 08:36 examples -> /usr/share/doc/spark-1.6.1/examples
drwxr-xr-x 3 root root  4096  6月 20 08:36 extras
drwxr-xr-x 2 root root  4096  6月 20 08:36 lib
drwxr-xr-x 6 root root  4096  6月 20 08:36 python
drwxr-xr-x 2 root root  4096  6月 20 08:36 sbin
lrwxrwxrwx 1 root root    19  6月 20 08:36 work -> /var/run/spark/work
drwxr-xr-x 3 root root  4096  6月 20 08:33 yarn

ですが、前述でconfがシンボリックリンクとなっているように、実際にEMRのマスターノードでlog4j.propertiesが格納されているディレクトリは/etc/spark/conf.distとなっています。

[hadoop@ip-172-31-30-193 ~]$ ll /usr/lib/spark/conf
lrwxrwxrwx 1 root root 15  6月 20 08:36 /usr/lib/spark/conf -> /etc/spark/conf
[hadoop@ip-172-31-30-193 ~]$ ll /etc/spark/conf
lrwxrwxrwx 1 root root 28  6月 20 08:36 /etc/spark/conf -> /etc/alternatives/spark-conf
[hadoop@ip-172-31-30-193 ~]$ ll /etc/alternatives/spark-conf
lrwxrwxrwx 1 root root 20  6月 20 08:36 /etc/alternatives/spark-conf -> /etc/spark/conf.dist
[hadoop@ip-172-31-30-193 ~]$ ll /etc/spark/conf.dist
合計 56
-rw-r--r-- 1 root root  987  6月 10 01:35 docker.properties.template
-rw-r--r-- 1 root root 1105  6月 10 01:35 fairscheduler.xml.template
-rw-r--r-- 1 root root 1733  6月 20 08:36 log4j.properties
-rw-r--r-- 1 root root 1734  6月 10 01:35 log4j.properties.template
-rw-r--r-- 1 root root 6671  6月 20 08:36 metrics.properties
-rw-r--r-- 1 root root 6671  6月 10 01:35 metrics.properties.template
-rw-r--r-- 1 root root  865  6月 10 01:35 slaves.template
-rw-r--r-- 1 root root 2409  6月 20 08:37 spark-defaults.conf
-rw-r--r-- 1 root root 1292  6月 10 01:35 spark-defaults.conf.template
-rwxr-xr-x 1 root root 1583  6月 20 08:36 spark-env.sh
-rwxr-xr-x 1 root root 4209  6月 10 01:35 spark-env.sh.template

また、Sparkを自前でインストールする際はlog4j.properties.templateを利用すると思いますが *3、差分は実質ありませんでした。

[hadoop@ip-172-31-30-193 ~]$ diff /usr/lib/spark/conf/log4j.properties /usr/lib/spark/conf/log4j.properties.template
19c19
< log4j.rootCategory=INFO,console
---
> log4j.rootCategory=INFO, console

log4j.propertiesが読み込まれる仕組みについて

ではそろそろ本題です。ご存知の方も多いかもしれませんが、log4j.propertiesはlog4j.configurationシステムプロパティで読み込まれる設定ファイルです *4。ということは、Spark shellアプリケーションが起動する際のjavaコマンドの引数にシステムプロパティとして-Dlog4j.configurationが指定されている可能性が高いわけです *5。そして、実際にSpark shellアプリケーションが起動する際にはlog4j.configurationシステムプロパティを利用してlog4j.propertiesを読み込んでいます。具体的にはSPARK_HOME/conf/spark-defaults.conf内のspark.driver.extraJavaOptionsにおいて-Dlog4j.configurationが指定されています。

[hadoop@ip-172-31-30-193 ~]$ grep spark.driver.extraJavaOptions /usr/lib/spark/conf/spark-defaults.conf
spark.driver.extraJavaOptions    -Dlog4j.configuration=file:///etc/spark/conf/log4j.properties -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=70 -XX:MaxHeapFreeRatio=70 -XX:+CMSClassUnloadingEnabled -XX:MaxPermSize=512M -XX:OnOutOfMemoryError='kill -9 %p'

spark-defaults.confが読み込まれるまでの処理フロー

先に結論から言うと、spark-defaults.confはorg.apache.spark.launcherAbstractCommandBuilderというJavaクラスのloadPropertiesFileメソッド内で読み込まれます。

AbstractCommandBuilder.java

    } else {
      propsFile = new File(getConfDir(), DEFAULT_PROPERTIES_FILE);
    }

前述のDEFAULT_PROPERTIES_FILE定数の実体が"spark-defaults.conf"という文字列です。また、getConfDirメソッドの箇所でSPARK_CONF_DIRおよびSPARK_HOMEからconfディレクトリを取得する実装になっています。

そして、実際にSpark shellアプリケーションを起動する処理の過程で実行されるJavaクラスはorg.apache.spark.repl.Mainになります。このクラスを経由してorg.apache.spark.repl.SparkSubmitCommandBuilderクラスが実行され、その処理の過程でSparkSubmitCommandBuilderの親クラスであるAbstractCommandBuilderクラスのloadPropertiesFileメソッドが呼び出されるという流れになっています。

org.apache.spark.repl.Mainが実行されるまでの処理フロー

ここまでをまとめると、コマンドライン上でspark-shellと入力すると途中でorg.apache.spark.repl.MainというJavaクラスが起動されて最終的に起動されるSpark shellアプリケーションを起動する際のコマンドライン引数が生成されるという流れになっていたわけです。では実際にspark-shellからorg.apache.spark.repl.Mainまでの流れについて確認したいと思います。

まずspark-shellですが、これは/usr/bin/spark-shellになります。

[hadoop@ip-172-31-30-193 ~]$ which spark-shell
/usr/bin/spark-shell

中身はJAVA_HOMEを読み込んだ上で、/usr/lib/spark/bin/spark-shellを起動しています。

#!/bin/bash

# Autodetect JAVA_HOME if not defined
. /usr/lib/bigtop-utils/bigtop-detect-javahome

exec /usr/lib/spark/bin/spark-shell "$@"

次に/usr/lib/spark/bin/spark-shellですが、最初に環境変数SPARK_HOMEの存在を確認し、存在しなければspark-shellファイルのパスからその値を決定します。EMRの場合は環境変数SPARK_HOMEが指定されていないため、ここでSPARK_HOMEの値が/usr/lib/spark/になります。

spark-shell

if [ -z "${SPARK_HOME}" ]; then
  export SPARK_HOME="$(cd "`dirname "$0"`"/..; pwd)"
fi

そして、spark-submitコマンドを実行します。実行するクラスはorg.apache.spark.repl.Mainで、これがSpark shellアプリケーションになります。

    "${SPARK_HOME}"/bin/spark-submit --class org.apache.spark.repl.Main --name "Spark shell" "$@"

次に/usr/lib/spark/bin/spark-submitですが、spark-classコマンドを実行するようになっています。

spark-submit

exec "${SPARK_HOME}"/bin/spark-class org.apache.spark.deploy.SparkSubmit "$@"

最後に/usr/lib/spark/bin/spark-classです。org.apache.spark.launcher.Mainが起動されているのが分かりますね！

spark-class

CMD=()
while IFS= read -d '' -r ARG; do
  CMD+=("$ARG")
done < <("$RUNNER" -cp "$LAUNCH_CLASSPATH" org.apache.spark.launcher.Main "$@")
exec "${CMD[@]}"

最後に

興味本位で調べてみたら、思った以上に複雑な仕組みになっておりびっくりしました。考えてみればSparkのような分散処理フレームワークが対象とする処理は少なくとも数秒以上かかる処理ばかりですし、Scala, Java, Python, Rといった複数の言語をサポートする上でアプリケーションの起動速度よりも、起動する仕組みをJavaで実装して保守性を優先するのは当然のことかもしれませんね。

参考

脚注

  1. SPARK_CONF_DIR で指定する方法もあります。 http://spark.apache.org/docs/1.6.1/configuration.html#overriding-configuration-directory ↩
  2. 正確には環境変数 SPARK_HOME は設定されていないため /usr/lib/spark/bin/spark-shell で内部的に付与されます。 ↩
  3. http://spark.apache.org/docs/1.6.1/configuration.html#configuring-logging ↩
  4. https://logging.apache.org/log4j/1.2/manual.html#Default_Initialization_Procedure ↩
  5. クラスパス経由で読み込まれるケースもありますので。 ↩

Share this article

facebook logohatena logotwitter logo

関連記事

GPTが自社の情報を正しく学習するためにはWebサイトをセマンティックなHTMLでマークアップした方がよい説

GPTが自社の情報を正しく学習するためにはWebサイトをセマンティックなHTMLでマークアップした方がよい説

User avatar
motchie
2023.03.14
AWS Glue ETLライブラリを使ってローカルでSparkを動かす

AWS Glue ETLライブラリを使ってローカルでSparkを動かす

User avatar
山下勝美
2020.01.21
Spark SQLによる値のハッシュ化を試してみた

Spark SQLによる値のハッシュ化を試してみた

User avatar
大高大輔
2019.08.28
AWS Glue ジョブタイプ『Spark』が Apache Spark 2.4.3 と Python 3.6をサポートしました

AWS Glue ジョブタイプ『Spark』が Apache Spark 2.4.3 と Python 3.6をサポートしました

User avatar
石川覚
2019.07.25
Classmethod's white logo
Facebook's logo
X's logo
YouTube's logo

© Classmethod, Inc. All rights reserved.